It looks like this is a per-extension timeout, won't CRP timeout well before this for multiple extensions?

This is the timeout value per dependency level.
CRP has an independent time out value. I will start an email thread including the CRP-side owner, on when/how to update the CRP timeout value.

Nit - doesn't timedelta have a min property?

Let's not keep converting between seconds and minutes, it's an easy thing to miss.

This is a strange construct - a while not around an if - please clean up.

Seems odd, why is this True?

Some extensions do not report any status. We should not wait for such extensions to report status. That's why we return True here.

But by returning True here we are saying that a extension that has not reported status yet has succeeded... correct?

Yes. I think we can return False in this case. @uiri do you have any comment on this?

collect_ext_status returns None if the extension does not report any status. Not all extensions report status.

If you return False in this case, the agent will hang until it times out on such extensions.

Base on offline discussion with @uiri , an extension can install and enable but may not create any status file. In this case, we don't want to wait for it until it is timed out. So we return True in this case.

TBD: What should we return if there is no status file?

If this is your default, you are not really testing for success, but failure.

Seems like a long wait.

Still not sure I agree with the way this is done, which is the feedback I gave @uiri previously. If the dependency chain is simple, this should be just an ordering problem. The way this is built allows for a more complex scenario (A depends on B and C), which was not my expectation. Please clarify.

Missing None check for dependency.ext.

This is not the correct behaviour.

The extension should not be run if its dependency timed out. The extension runs once this function returns, unless this function throws an exception.

Why has this logic been removed entirely?

Further divergence from the Windows agent is not desirable.

Why not simply move through the extHandlers sorted by dependency level, and remove all the additional wait code?

We not only make sure the extensions are installed sequentially, we need to make sure that the previous extension in the sequence is installed successfully before proceeding with the next extension in the sequence. Hence this wait code with different timeout value for each level.

Consider something like this:

  for ext_handler in extHandlers:
    handle_ext_handler(ext_handler)
    wait_if_necessary(ext_handler)

Seems a little bit simpler than tracking full dependencies per se. We really just care if the last handler is done, if there is a stated dependency.

Regarding the timeouts, I thought we had decided on a total 90?

Agree with @hglkrijger that the for loop can be simplified to not make reference to the dependencies, but just ext_handler. Are the dependencies used only to increase the timeout 90 min per dependency level?

Even now, the for loop does not make any reference to the dependency. It just references what was the previous extension installed in order to wait on that.

I think the one @hglkrijger suggests is that 'install an extension, wait for it'.This has a side effect of waiting for the highest level extensions as well, which is not required to be waited for.

Another way based on his suggestion is 'install an extension, wait for it if it is not the highest dependency level'. This requires calculating the highest dependency level in advance.
Do you think we need to change the logic to match this?

per offline discussion we will got for a flat 90 min (instead of 90 per dependency level)

status is an instance of ExtensionStatus, so format will produce something like "<...ExtensionStatus object at 0x000001BF0B6B7DA0>"

@hglkrijger - what is the interpretation of status/substatus/status?... are extensions allowed to report "success" in status and, say, "error" in one of the status/substatus/status? is this considered an extension error?

Per offline discussion @sirajudeens will double-check the validation of substatus in CRP to be sure this matches.

do we need to catch these errors? this bumps the priority to 0.

We expect string value corresponding to an integer value, which is parsed to get the integer value.
In order to guard against any corrupted value, we catch this exception. The dependency level is set to default in in that case. We assume that that kind of extension does not depend on anything so it gets its priority bumped up. Do you have any better suggestion in this case?

OK, I double-checked the previous code and it was doing the same (setting the priority to 0 on error). I think we should log a warning in case bumping it up to 0 affects any dependencies and causes an extension failure.

I think this warning is going to create a lot of noise in the logs if the platform is only sending down dependencyLevel for the cases where dependencies exist.

@sirajudeens are we sending down dependencyLevel all the time regardless or only when the customer specifies dependencies? What about for single VMs?

I think it would be more useful for debugging and logging to define a __str__ method on ExtensionStatus and return the full status.

I would cleanup this loop a little, maybe something like

first = self.ext_handlers.extHandlers[0].sort_key() if len(extHandlers) > 0 else None
for i in range(1, len(self.ext_handlers.extHandlers)):
    if self.ext_handlers.extHandlers[i].sort_key() != first:
        return True
return False

The whole method seems unnecessary. The agent should not wait for the leaf nodes. In the case where there are no dependencies, every node is a leaf node.

I would suggest switching the order of the calls to handle_ext_handler and wait_for_prev_handler_completion (call handle first and wait second) and just add a check to avoid waiting for the last extension. I think this would express the intention of the code a little more clearly.

(I'd suggest something similar to

for i in range(len(self.ext_handlers.extHandlers)):
    self.handle_ext_handler(self.ext_handlers.extHandlers[i], etag)

    if ext_seq_required:
        dep_level = ext_handler.sort_key()
        if dep_level >= 0:
            if i < len(self.ext_handlers.extHandlers) - 1 and !self.wait_for_handler_successful_completion(self.ext_handlers.extHandlers[i], wait_until):
                break

plus updating the comments)

Please don't use for i in range(L) in a Python 2 or Python 2/3 codebase such as this one. It creates a list of integers unnecessarily.

For this particular case, keeping track of i is unnecessary. The second to last ext_handler may also be a leaf node so the test needs to be against the maximum dependency level, not against its position in the list. if dep_level >= 0 and dep_level < max_dep_level: ought to be a sufficient test.

agree

Let's add a comment to explain the >=0 (we do this only for install/enable and not for uninstall/disable)

I would remove 'prev_' from the name of this function and its parameters. The function just waits for a handler, by itself it doesn't have a concept of "previous handler"

I would suggest renaming the function to wait_for_handler_successful_completion or similar

if implementing the changes suggested for the handle/wait loop on line 320, then there is no need to keep track of the previous handler and this check for null is not needed

Suggest rephrasing this message to something similar to "Extension {0} did not reach a terminal state within the allowed timeout. Last status was {1}"

Disagree. If the extension completes within the allotted time but returns an error, you still wind up emitting this message. Your suggestion makes that error sound like a timeout. The right thing to do is to cleanly separate the "returned an error" condition from the "did not complete within the allotted time limit" condition, emitting a clear (and distinct) message for each of those two cases.

@jasonzio , is your concern about the error message or the functionality itself when there is a failure?
As per the last discussion with the VM agent folks, if an extension timedout/failed, we should stop processing the rest of the extensions, when the extension sequencing is required.

@jasonzio agree that 2 separate messages would be better

Let's add a message saying we stopped processing other extensions

I think there no need to return an ExtensionStatus object. I think only the 'status' field is used by the code

I think only the 'status' field is used by the code

It will be easier to debug if we have the entire status object and not just the fields used by the code. Also, it is impossible to tell whether it is a status or a substatus otherwise.

No more substatus per @narrieta 's suggestion.

"no status file" or similar may be more appropriate

We need to update the comment... this condition would be reached when seq < 0 (i.e. no new user settings) rather than when there is no status file

this variable is not referenced anymore

this is done for install and enable; let's update the comment to reflect that

Let's add the extension name and rephrase the message to read something similar to "Extension {0} failed or timed out, will skip processing the rest of the extensions"

This will be too much logging. We already log the extension name in the wait function. This is to just log that the rest of the extensions will be skipped.

Sure, we can leave the extension name out if you prefer so. Let's be explicit about why we are skipping the rest of the extensions, though. Maybe something like "An extension failed or timed out, will skip processing the rest of the extensions". Hopefully this will be more helpful for CSS or a customer reading the log.

Minor: "Status was" instead of "Last status was"

typo: "timout"

let's remove "test" from the name of this helper function. this threw me off... gave me the impression that it was a test

we should change this status... this gives the impression that the extension is reporting a warning when in actuality there is no status file. I would suggest return something like "status file not found" or similar